Fix resume succeding prematurely#1573
Conversation
2303b41 to
56c9bb2
Compare
Coverage Report for CI Build 26640184155Coverage increased (+0.05%) to 85.357%Details
Uncovered Changes
Coverage RegressionsNo coverage regressions found. Coverage Stats
💛 - Coveralls |
xstoicunicornx
left a comment
There was a problem hiding this comment.
I like how you are breaking out session level information but I think this solution is a bit over engineered and it seems unnecessary to introduce additional state.
My comments below are a bit general but feel free to take more concrete direction from my branch https://github.com/xstoicunicornx/rust-payjoin/tree/pr1573-alt
0809f0c to
0e3690a
Compare
xstoicunicornx
left a comment
There was a problem hiding this comment.
A bit more feedback.
| } => { | ||
| println!("All resumed sessions completed."); | ||
| let closed = results.iter().filter(|r| matches!(r, Ok(Ok(())))).count(); | ||
| let total = spawned_recv_ids.len() + spawned_send_ids.len(); |
There was a problem hiding this comment.
| let total = spawned_recv_ids.len() + spawned_send_ids.len(); | |
| let total = results.len(); |
Why not just this? Then the spawned_recv_ids and spawned_send_ids aren't needed anymore.
| wait_for_stdout_match(&mut stdout, |line| { | ||
| line.contains("All resumed sessions completed.") | ||
| }), | ||
| wait_for_stdout_match(&mut stdout, |line| line.contains("Resume done:")), |
There was a problem hiding this comment.
| wait_for_stdout_match(&mut stdout, |line| line.contains("Resume done:")), | |
| wait_for_stdout_match(&mut stdout, |line| line.contains("1/1 session(s) closed.")), |
This is supposed to assert that the resumed session was completed, checking for "Resume done:" only asserts that summary was printed not that the session was actually closed.
| Err(_) => { | ||
| let id = persister.session_id(); | ||
| println!( | ||
| "No payjoin transaction seen yet (waited {timeout_duration:?}). Session {id} \ |
There was a problem hiding this comment.
| "No payjoin transaction seen yet (waited {timeout_duration:?}). Session {id} \ | |
| "No payjoin transaction seen yet, stopping (waited {timeout_duration:?} sec). Session {id} \ |
| let id = persister.session_id(); | ||
| println!( | ||
| "No payjoin transaction seen yet (waited {timeout_duration:?}). Session {id} \ | ||
| remains open; run `payjoin-cli resume` to keep watching." |
There was a problem hiding this comment.
| remains open; run `payjoin-cli resume` to keep watching." | |
| remains open. Run `payjoin-cli resume` to keep watching." |
nit: semicolon isn't used anywhere else
There was a problem hiding this comment.
thanks for catching that
| } | ||
| } | ||
| println!( | ||
| "Resume done: {closed}/{total} session(s) closed. \ |
There was a problem hiding this comment.
I don't think printing the completed/total sessions count is useful or worth the complexity. It seems sufficient to print per-session results (session XYZ either completed, is still polling, or had an error).
| Err(_) => { | ||
| let id = persister.session_id(); | ||
| println!( | ||
| "No payjoin transaction seen yet (waited {timeout_duration:?}). Session {id} \ | ||
| remains open; run `payjoin-cli resume` to keep watching." | ||
| ); | ||
| Err(anyhow!( | ||
| "No payjoin transaction detected in mempool within {timeout_duration:?}" | ||
| )) | ||
| } |
There was a problem hiding this comment.
this change seems unrelated to the resume fix, if really necessary it should be a separate commit.
There was a problem hiding this comment.
Yes , it's not related to resume fix , more like a helpful ux . i'll extract to diff commit or drop it entirely
This addresses payjoin#1545, upon resuming a session where the sender posted the original proposal but went ofline, the cli succeds prematurely and outputs "payjoin transaction detected in mempool" because the cli treats any Ok(_) as scucess. This also addresses a subtle issue where after a certain period without tx detected in the mempool the the monitor_proposal function returned Err("Timeout waiting for payment confirmation after 5s"). That looked like a failure even though the session should stay open in Monitor. And finally the missleading "All resumed sessions completed" message. Co-authored-by: xstoicunicornx <xstoicunicornx@users.noreply.github.com>
0ed9646 to
7779c42
Compare
| } | ||
|
|
||
| let mut tasks = Vec::new(); | ||
| //let mut tasks = Vec::new(); |
There was a problem hiding this comment.
| //let mut tasks = Vec::new(); |
Remove comment
There was a problem hiding this comment.
that was a mistake , thanks for catching it
| if all_completed { | ||
| println!("All resumed sessions completed."); | ||
| } |
There was a problem hiding this comment.
Since completion is being printed session by session already I think it would be better to just print a "Done" message here to indicate the resume has concluded.
There was a problem hiding this comment.
Sorry what I meant was that it should print "Done" regardless of whether all sessions were completed or not just to indicate that the resume command has finished. But tbh maybe we don't really need to print anything here anymore.
There was a problem hiding this comment.
oh!, i misunderstood you. Imho telling users that all resumed session completed is helpful . The "All resumed sessions completed" message can stay as it is and then we also have a diff message that indicates the Resume command is done. I also agree that not printing anything does not affect UX adversely.
There was a problem hiding this comment.
would love to hear your opinion @xstoicunicornx before i push the new changes
There was a problem hiding this comment.
Given that every resumed session now prints whether the session completed or not, I feel like the user can already easily tell if all resumed session completed or not. So imo it doesn't convey any additional helpful information.
| let id = persister.session_id(); | ||
| println!( | ||
| "No payjoin transaction seen yet, stopping (waited {timeout_duration:?} seconds). Session {id} \ | ||
| remains open. run `payjoin-cli resume` to keep watching." | ||
| ); |
There was a problem hiding this comment.
We don't need this anymore now that errors are printed to the user upon task completion.
| remains open. run `payjoin-cli resume` to keep watching." | ||
| ); | ||
| Err(anyhow!( | ||
| "No payjoin transaction detected in mempool within {timeout_duration:?}" |
There was a problem hiding this comment.
| "No payjoin transaction detected in mempool within {timeout_duration:?}" | |
| "No payjoin transaction detected in mempool within {timeout_duration:?} sec, stopping." |
I think this small change would make it much more clear what is happening.
|
|
||
| pub fn session_id(&self) -> SessionId { self.session_id.clone() } |
There was a problem hiding this comment.
This shouldn't be needed anymore.
|
|
||
| terminate(cli_resumer).await.expect("Failed to kill payjoin-cli"); | ||
| assert!(res.is_some(), "Expected all resumed sessions completed"); | ||
| assert!(res.is_some(), "Expected resume summary with all sessions closed"); |
There was a problem hiding this comment.
Looks like this line change is leftover from previous version of this PR.
7779c42 to
60a03aa
Compare
xstoicunicornx
left a comment
There was a problem hiding this comment.
Getting there :)
| tasks.push(tokio::spawn(async move { | ||
| self_clone.process_sender_session(sender_state, &sender_persister).await | ||
| })); | ||
|
|
There was a problem hiding this comment.
nit: extra line added here
| if all_completed { | ||
| println!("All resumed sessions completed."); | ||
| } |
There was a problem hiding this comment.
Sorry what I meant was that it should print "Done" regardless of whether all sessions were completed or not just to indicate that the resume command has finished. But tbh maybe we don't really need to print anything here anymore.
| let timeout = tokio::time::Duration::from_secs(10); | ||
| let res = tokio::time::timeout( | ||
| timeout, | ||
| wait_for_stdout_match(&mut stdout, |line| line.contains("Done.")), |
There was a problem hiding this comment.
| wait_for_stdout_match(&mut stdout, |line| line.contains("Done.")), | |
| wait_for_stdout_match(&mut stdout, |line| { | |
| line.starts_with("Session ") && line.ends_with(" completed.")) | |
| }, |
Better to key off of the print message that actually indicates the session was completed.
| wait_for_stdout_match(&mut stdout, |line| { | ||
| line.contains("All resumed sessions completed.") | ||
| || line.contains("No sessions to resume.") |
There was a problem hiding this comment.
| wait_for_stdout_match(&mut stdout, |line| { | |
| line.contains("All resumed sessions completed.") | |
| || line.contains("No sessions to resume.") | |
| wait_for_stdout_match(&mut stdout, |line| { | |
| line.starts_with("Session ") && line.ends_with(" completed.") |
Same with this one. Plus not finding a string containing either of these no longer means that a session was not completed.
60a03aa to
fb01450
Compare
xstoicunicornx
left a comment
There was a problem hiding this comment.
This looks good. Just one bad suggestion that I made that needs to be reverted (sorry... I didn't realize until I ran the test locally)
| Err(_) => Err(anyhow!( | ||
| "Timeout waiting for payment confirmation after {:?}", | ||
| timeout_duration | ||
| "No payjoin transaction detected in mempool within {timeout_duration:?} seconds, stopping." |
There was a problem hiding this comment.
| "No payjoin transaction detected in mempool within {timeout_duration:?} seconds, stopping." | |
| "No payjoin transaction detected in mempool within {timeout_duration:?}, stopping." |
I was wrong about adding the "seconds", its already included as part of the timeout_duration.
There was a problem hiding this comment.
Also terrible that i missed it myself
fb01450 to
f3bc1ab
Compare
xstoicunicornx
left a comment
There was a problem hiding this comment.
utACK f3bc1ab
Solution is fairly minimal yet implements error handling and improves clarity of messages printed to the user. It also includes testing to guard against this bug in the future.
|
@zealsham just updated your description to use the "resolves #issue-number" pattern which will automatically link this PR to that issue (and close that issue when this is merged). |
This resolves #1545, upon resuming a session where the sender posted the original proposal but went ofline, the cli succeds prematurely and outputs "payjoin transaction detected in mempool" because the cli treats any Ok(_) as sucess.
This also addresses a subtle issue where after a certain period without tx detected in the mempool the the monitor_proposal function returned
Err("Timeout waiting for payment confirmation after 5s").
That looked like a failure even though the session should stay open in Monitor. And finally the missleading "All resumed sessions completed" message.
my initial analysis of the issue in #1545 was wrong, as the intended solution witht that did not fix it. i had LLM (gemini) help with some of the root cause analysis
Pull Request Checklist
Please confirm the following before requesting review:
AI
in the body of this PR.